Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mempool syncing optimizations & fixups #89

Merged
merged 7 commits into from
Oct 1, 2024

Conversation

shesek
Copy link
Collaborator

@shesek shesek commented Jun 1, 2024

Optimizations:

  • Send RPC requests in parallel over multiple TCP connections, without batching (38e73d9)

    The number of parallel requests to send can be controlled with a new --daemon-parallelism CLI options (defaults to 4).

  • Continuously attempt to fetch a full mempool snapshot, keeping whatever transactions we were able to get each time (6a14f40)

Fixups (not strictly necessary for the other changes, but touches on related areas and the previous behavior was wrong):

  • Don't add transactions with unknown parents to ensure mempool consistency (c60207a)

  • Make sure the chain tip doesn't move while fetching the mempool (a6a796c)

This will require adjusting bitcoind's rpcthreads and possibly rpcworkqueue configuration options upwards. The default rpcthreads is 4, which would be exhausted by mempool fetching alone (electrs keeps at least one other open connection, and we probably want to allow some room for other clients too).

Based on top of #76. (now merged)

@philippem
Copy link
Collaborator

Overall this MR seems to greatly improve the initial sync and steady state of electrs alongside a slower bitcoind.

some issues found during testing

RCasatta
RCasatta previously approved these changes Jun 10, 2024
Copy link
Collaborator

@RCasatta RCasatta left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK a6a796c code review

My comments are mostly styling and perf improv.

Note also I am not that familiar with the overall codebase, but all changes seems reasonable/

src/new_index/schema.rs Outdated Show resolved Hide resolved
src/new_index/schema.rs Outdated Show resolved Hide resolved
src/daemon.rs Show resolved Hide resolved
src/daemon.rs Outdated Show resolved Hide resolved
src/daemon.rs Outdated Show resolved Hide resolved
src/daemon.rs Outdated Show resolved Hide resolved
src/new_index/mempool.rs Outdated Show resolved Hide resolved
src/new_index/mempool.rs Show resolved Hide resolved
src/daemon.rs Outdated Show resolved Hide resolved
@philippem
Copy link
Collaborator

* some requests from electrs to bitcoind will disconnect waiting for recv, at https://github.com/shesek/electrs/blob/202405-mempool-sync/src/daemon.rs#L210
  Increasing the `rpcthreads` parameter in bitcoind does not seem to change this. Electrs itself seems to recover. These recv disconnects happen with different rpcs (usually `getrawtransaction`, but also `getbestblockhash`)

While tracing this with wireshark, I observed that electrs sends a request (such as getbestblockhash), and waits for a response. After 30 seconds (and a few TCP Keep-Alive interactions), bitcoind sends a FIN,ACK without any text response. Seems to be some behaviour in bitcoind.

shesek added a commit to shesek/electrs that referenced this pull request Aug 6, 2024
shesek added a commit to shesek/electrs that referenced this pull request Aug 6, 2024
@shesek
Copy link
Collaborator Author

shesek commented Aug 6, 2024

the electrum method blockchain.transaction.get will panic on the handling thread if the transaction is not known by electrs

I was unable to reproduce this, the "missing transaction" message appears to be returned as a JSONRPC error without panicking:

# Client
$ echo '{"id": 1, "method": "blockchain.transaction.get", "params": ["0000000000000000000000000000000000000000000000000000000000000000"]}' | nc 172.17.0.3 60401
{"error":"missing transaction","id":1,"jsonrpc":"2.0"}

# Server logs
TRACE RPC Request("{\"id\": 1, \"method\": \"blockchain.transaction.get\", \"params\": [\"0000000000000000000000000000000000000000000000000000000000000000\"]}\n")
WARN rpc #1 blockchain.transaction.get [String("0000000000000000000000000000000000000000000000000000000000000000")] failed: Error: missing transaction
TRACE RPC Done
# ... keeps running

Seems to be some behaviour in bitcoind.

I'm seeing that behaviour on my local regtest env too.

@RCasatta
Copy link
Collaborator

RCasatta commented Aug 9, 2024

utACK a6c181e

RCasatta
RCasatta previously approved these changes Aug 13, 2024
philippem pushed a commit that referenced this pull request Aug 13, 2024
shesek added a commit to shesek/electrs that referenced this pull request Aug 13, 2024
RCasatta
RCasatta previously approved these changes Aug 14, 2024
Copy link
Collaborator

@RCasatta RCasatta left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK f3a13e7

@philippem
Copy link
Collaborator

in analyzing pcap trace between local electrs and local. bitcoin rpc, we see electrs asking for getrawmempool on
3 times in 16 seconds, in a single socket connection. MR needs more analysis/testing.

@philippem philippem marked this pull request as draft August 16, 2024 16:47
@philippem
Copy link
Collaborator

2 issues

  • repeated requests for full mempool on one thread (correct?)

  • disconnects are actually coming from electrs, not bitcoind (screenshot of pcap)

image

@philippem
Copy link
Collaborator

2024-08-16T09:26:16.938-07:00 - INFO NetworkInfo { version: 270000, subversion: "/Satoshi:27.0.0/", relayfee: 1e-5 }
2024-08-16T09:26:16.938-07:00 - INFO BlockchainInfo { chain: "main", blocks: 857053, headers: 857053, bestblockhash: "00000000000000000003066eeec0d73da4cf50ee6bf7e31f9032145c17ad3d54", pruned: false, verificationprogress: 0.9999971, initialblockdownload: Some(false) }
2024-08-16T09:26:34.141-07:00 - INFO hash=00000000000000000003066eeec0d73da4cf50ee6bf7e31f9032145c17ad3d54 height=857053 @ 2024-08-16T16:18:23Z (2 left to index)
2024-08-16T09:27:14.773-07:00 - INFO Electrum RPC server running on 0.0.0.0:50001
2024-08-16T09:27:14.777-07:00 - INFO REST server running on 0.0.0.0:3001
2024-08-16T09:27:19.773-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.264-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.264-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.265-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.266-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.267-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:23.267-07:00 - WARN reconnecting to bitcoind: disconnected from daemon while receiving
2024-08-16T09:27:26.691-07:00 - WARN chain tip moved while updating mempool
2024-08-16T09:27:26.691-07:00 - WARN skipped failed mempool update, trying again in 5 seconds
2024-08-16T09:27:31.692-07:00 - INFO hash=000000000000000000008e575ea9a5b9bcd0591f6b749f975fd679fc8ca23e62 height=857054 @ 2024-08-16T16:26:43Z (1 left to index)

@philippem
Copy link
Collaborator

following one of the "disconnects":

  1. electrs makes RPC request for "getrawtransaction"
  2. bitcoind responds with data
  3. electrs sits on connection for 30 seconds
  4. bitcoin sends FIN,ACK but electrs does not close
  5. electrs attempts to send more
  6. bitcoin sends RST

electrs should be responding to the FIN,ACK and active, and reopen

image

Copy link
Collaborator

@philippem philippem left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see earlier comments about connection handling.

@philippem
Copy link
Collaborator

  • we are also seeing 5 second delays after receiving 500 from bitcoin. The 500 error is used by bitcoin rpc to indicate that the getrawtransaction call requested a non existent tx, which will happen after blocks are mined, and in presence of full rbf. Electrs should consider this case of error by inspecting the details of the json-rpc response, and not wait 5 seconds.

@RCasatta RCasatta dismissed their stale review August 19, 2024 06:35

I misread the comment about the disconnects

@shesek
Copy link
Collaborator Author

shesek commented Aug 20, 2024

repeated requests for full mempool on one thread ... we see electrs asking for getrawmempool on 3 times in 16 seconds, in a single socket connection

getrawmempool is used to get the list of mempool txids (not txs), and should be sent from the main (sync loop) thread using the same socket (unless it disconnects). It should be sent at least once every 5 seconds, possibly more if additional roundtrips are needed to get a full mempool view.

The 500 error is used by bitcoin rpc to indicate that the getrawtransaction call requested a non existent tx ... Electrs should consider this case of error by inspecting the details of the json-rpc response, and not wait 5 seconds.

This should already be the case. In fact only errors explicitly constructed as an ErrorKind::Connection would trigger the automatic reconnection behavior, other errors will bubble up. RPC errors for "tx not found" are identified and ignored, while other unexpected RPC errors terminate execution (without reconnecting).

disconnects are actually coming from electrs, not bitcoind (screenshot of pcap)

Looking into this.

@shesek
Copy link
Collaborator Author

shesek commented Aug 28, 2024

electrs sits on connection for 30 seconds .. bitcoin sends FIN,ACK but electrs does not close

bitcoind appears to close the connection after a period of inactivity, which can be adjusted with the (hidden) config option rpcservertimeout (defaults to 30 seconds).

Adjusting it upwards made the disconnection issues I was experiencing in my local env go away. I also tested with electrs and bitcoind connected over the internet (local electrs connecting to a regtest bitcoind on a vps) and was able to retain open TCP connections with no disconnections for several hours (used every ~2 minutes, with rpcservertimeout set to 5 minutes).

I also tried investigating what's causing electrs not to close immediately in reply to bitcoind's FIN, but do not have an answer yet.

This actually hurts performance because the batched response has to be
bueffered on the bitcoind side, as @TheBlueMatt explains at
romanz#373 (comment)

Instead, send multiple individual RPC requests in parallel using a
thread pool, with a separate RPC TCP connection for each thread.

Also see romanz#374
The indexing process was adding transactions into the store so that
prevouts funded & spent within the same batch could be looked up via
Mempool::lookup_txos(). If the indexing process later failed for any
reason, these transactions would remain in the store.

With this change, we instead explicitly look for prevouts funded within
the same batch, then look for the rest in the chain/mempool indexes and
fail if any are missing, without keeping the transactions in the store.
Previously, if any of the mempool transactions were not available
because they were evicted between getting the mempool txids and txs
themselves, the mempool syncing operation would be aborted and tried
again from scratch.

With this change, we instead keep whatever transactions we were able to
fetch, then get the updated list of mempool txids and re-try fetching
missing ones continuously until we're able to get a full snapshot.
- Reduce logging level for bitcoind's JSONRPC response errors

  These can happen pretty often for missing mempool txs and do not
  warrant warn-level logging. Unexpected RPC errors will bubble up and
  be handled appropriately.

- Add more verbose logging for mempool syncing
Keep RPC TCP connections open between sync runs and reuse them,
to reduce TCP connection initialization overhead.
@shesek
Copy link
Collaborator Author

shesek commented Sep 11, 2024

Rebased and added some more verbose logging for mempool syncing.

@philippem
Copy link
Collaborator

testing latest commit using local electrs and bitcoind, I set parameters in bitcoin.conf

rpcthreads=16
rpcservertimeout=600
rpcworkqueue=50

I have not seen any "disconnected from daemon while receiving" messages.

@philippem philippem marked this pull request as ready for review September 12, 2024 22:31
@RCasatta
Copy link
Collaborator

RCasatta commented Sep 21, 2024

utACK 7a068bf

@RCasatta RCasatta merged commit 5168871 into Blockstream:new-index Oct 1, 2024
2 checks passed
rem1-dev pushed a commit to rem1-dev/electrs that referenced this pull request Nov 5, 2024
rem1-dev pushed a commit to rem1-dev/electrs that referenced this pull request Nov 5, 2024
rem1-dev pushed a commit to rem1-dev/electrs that referenced this pull request Nov 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants